日均万条数据丢失，一个隐式骚操作导致的奇葩事故！

主从复制作为 MySQL 的精髓，有两大困难：主从数据的延时与数据的不一致性。针对数据不一致的排查处理，相信各位大佬们都有丰富的处理经验，我就不多说了。

本文主要是给大家分享一个工作中遇到的奇葩事例：由于一个极隐式的骚操作，导致从库丢失数据（数据丢失量在每天将近万条记录）！

环境描述

业务环境：短时间内（几个月的时间），业务蓬勃发展，客户量从一两万一下增加到几十万用户。

数据库环境，如下图：

问题描述

某天，主库 10.0.0.1 的 CPU 使用率突然升高，均值达到 80%+，导致 Keepalived 的 VIP 漂移至从库 10.0.0.2。

理论上丢失的是切换过程中的几秒钟数据，业务侧对丢失的这几秒数据表示没关系，那么这个事件到此应该就结束了。

然而当天晚上，业务打电话过来说：丢失了部分用户信息，导致用户登入不了，要求帮忙恢复数据并查找数据丢失的原因。

本文对数据恢复这块就不具体展开了，稍微提一下，这边因为新主 10.0.0.2 已经有数据写入，只能对比用户表数据把新主少的数据导入进去。

初步排查

对于主从复制丢失数据，解决方法没有捷径，只能老老实实地跟踪数据复制过程，查看是哪里出了问题。

选择丢失数据中时间比较近的，时间为 2017-06-09 13:36:01，ID为 849791 这条数据，来跟踪整个复制过程，因为日志只保留 14 天的。

分析主库 binlog 日志，binlog 日志中是有这条记录的。

分析从库日志：因为数据库配置了 relay_log_purge 与 log-slave-updates，所以中继日志已经找不到这个时间点了，只能查看从库 binlog 日志。

然而在从库的 binlog 日志中并未找到这条记录，说明这条数据是未执行，排除后期人为删除的，那么数据为何不被执行呢？或者说数据是在执行过程中丢失的？

数据分析

无可用的中继日志怎么办？难道没办法查了？于是我决定观察和对比一下丢失的数据，看看其中是否含有什么规律，是不定时丢失数据，还是会在某些特定时刻丢失数据。

整理了一下某表丢失的数据，通过观察、分析丢失数据的属性（下图是我截取的部分列，最后一列的时间是创建时间，也就是写表时间）：

从图中可以看出，丢失的数据的插表时间都是在每分钟的前 2 秒。这不由地让人思考，为何丢失的数据是每分钟前 2 秒的呢？

而且数据丢失的时间间隔也不是很长，基本隔几天就肯定有数据丢失。经过这样分析，事情似乎就变得简单了。

深入调查

首先，关闭 log-slave-updates、relay_log_purge 等一切影响判断的额外参数设置，等待一段时间后，再来对比某表新数据丢失情况。

可以看到又有新数据丢失，根据这些丢失数据再来排查问题。

首先先查主库，查看主库的 binlog 日志状体信息状态。

就以 2017-6-17 15:17:02 最新丢失的这条数据来跟踪，查看主库 10.0.0.2 上的 binlog 日志中是否存在这条数据：

结果显示主库是存在这条数据的。

在登入从库查看 relay-log 日志情况，发现 relay-log 日志生成太频繁，每分钟生成 1 个 relay-log 日志，而且有些文件大小又不一致。

那么这套主从集群，业务肯定部署过分割 relay-log 日志的脚本，而且应该是 flush 来强制刷新的。如图：

我们先来看从库 relay-log 日志中是否存在这条数据，查找17分生成的relay日志，提取前 2 秒能匹配的插入情况。

发现并没有这条 insert 操作，难道数据未写入 relay 日志，刷新日志时导致事务丢失？ 把查询时间拉长至 50 秒。

发现也没有这条数据，并且数据跟前面 2 秒的一致，那么其它数据呢？会不会在下一个日志中？

赶紧去 18 分生成的 relay 日志查看，发现这条数据在 15:18 分这个 relay 日志中的第一个事务的位置。

那么是没有执行，还是执行过程丢失？仔细观察主库 binlog 与从 relay-log 日志的记录，也没能看出什么名堂，从事务开始到 commit，都一样。

问题定位

如果一条数据无法比较，那就再随机拿出几条丢失的数据来跟踪。发现情况都一样，数据都已经复制到 relay 日志中，而且内容根本看不出为何不能执行。

唯一有疑点的是这些事务都在日志的第一个事务中。顿时，我有种想法，会不会强制刷新 relay 日志，造成日志的第一个事务有时不执行，或执行过程中丢失？

如果是脚本引起的，那么除去这些事务未执行外，肯定还有其它事务也未执行。那么，我就随机选择几个 relay-log 日志，找到第一个事务。

具体分析如下：

再登入从库查询结果：

可以看出从库数据并未更新。随后，随机分析了几个 relay 日志，发现第一个事务都未被执行。而且操作的表都是有不同的，操作也是有不同，有 insert、update 等等，顿时感觉事情大条了。

如果每个日志的第一个事务都未执行，那么从库要缺少多少条数据？不敢想象，现在业务还在上升期，不久业务量会是现在的几倍，甚至更多，到那时就不是用户投诉那么简单了。

又抓取了部分 relay 日志情况，第一个事务也都未被执行。我可以肯定了，是所有 relay 日志的第一个事务都未被执行。

这个问题也可以是由于分割 relay 日志的脚本造成的。一般强制刷新日志是用 flush 命令来操作的，flush 命令一般不会造成数据丢失，当然像他们这样频繁的操作，我是不知道会不会造成 Bug，导致丢数据。

还有在 flush relay logs 的时候有没有用到其他的什么操作呢？我决定抓一把数据库中操作过的命令。

抓取命令，问题解决

想到就做，登上从库主机、登入数据库，开启 general_log 日志。坐等 5 分钟，打开日志，寻找每分钟前几秒的记录。

哇！哇！哇！

你们猜我看到了什么？ 我从未见过如此骚的操作！上图，以表我的震惊。

为什么要跳过事务？你用 stop slave 与 Start slave 来刷新 relay 日志，已经刷新了我的三观，那，有必要跳过事务？这就解释得通了，为何 relay 日志第一个事务全都丢失。

至此！问题已经清晰，是由于开发设置的分割 relay 日志的脚本，使用了非常规命令及 sql_slave_skip_counter 跳过事务命令来分隔 relay-log 日志，导致事务大量丢失。

所以，创新是好事，但要打好基本功，别搞些骚操作。

作者：洪凌

编辑：陶家龙、孙淑娟

本文转载自“DBAplus社群”微信公众号

洪凌

新炬网络资深 MySQL 工程师

超过 7 年 MySQL 数据库运维经验，擅长数据库运维体系、集群架构建设，熟悉 MySQL 性能优化，对数据库监控系统也有着独特的理解。

精彩文章推荐：